JVMのGCイベントのログをSlf4j経由でJSON形式でログとして出す

#Java

齋藤将也

2017.11.16

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

こんにちは。生魚美味しいですよね。今日久しぶりに食べましたが、やっぱり美味しい。どうも齋藤です。

今回はGCイベントのログをSlf4j経由で出力してみたいと思います。また、JSON形式でログを出力してみましょう。

今回作ったアプリケーションは以下のリポジトリにコードを置いております。

gclogger

はじめに

JVMのGCログは本来オラクルのサイトの記述を参考にすると -verbose:gc もしくは -Xloggc:filename を指定することで、標準出力もしくはファイル出力することができるようです。

しかし、アプリケーションのログ等ではSlf4jなどを使われているのではないでしょうか。

この記事では、JVMのGCイベントのログをSlf4j経由で出力してみます。また、この記事で書いたログで出力される内容は、JVM本体から出力されるGCログとは少し違う内容になります。

今回は、kotlinとSpring Bootを利用したアプリケーションで試してみますが今回の内容では触れません。

弊社のブログや他の方の記事を参考にすると良いのではないでしょうか。記事末尾に参考にしたブログを列挙しております。

今回利用するアプリケーションは以下のものです。

package com.github.wreulicke.gclogger

import com.netflix.spectator.gc.GcLogger
import org.slf4j.Logger
import org.slf4j.LoggerFactory
import org.springframework.boot.autoconfigure.SpringBootApplication
import org.springframework.boot.context.event.ApplicationReadyEvent
import org.springframework.boot.runApplication
import org.springframework.context.event.EventListener
import org.springframework.context.annotation.Bean
import org.springframework.http.MediaType
import org.springframework.web.reactive.function.server.ServerResponse
import org.springframework.web.reactive.function.server.router
import reactor.core.publisher.Flux
import java.util.*
import kotlin.collections.ArrayList


@SpringBootApplication
class GcLoggerApplication{
    companion object {
        private val log:Logger = LoggerFactory.getLogger(GcLoggerApplication::class.java)
    }

    // 真似しないでください。GCを発生させるためのエンドポイントです。
    @Bean
    fun routes() = router {
        GET("/test") {
            val list = ArrayList<String>()
            while (true){
                var uuid = UUID.randomUUID().toString()
                list.add(uuid);
                if (uuid == "") break
            }
            log.info(list.toString())
            ServerResponse.ok()
                    .contentType(MediaType.APPLICATION_JSON_UTF8)
                    .body(Flux.just("{\"message\":\"hello\"}"),String::class.java)
        }
    }
}

fun main(args: Array<String>) {
    runApplication<GcLoggerApplication>(*args)
}

導入方法

ライブラリを読み込んで、起動時にGcLoggerをnewしてstartするだけ。これだけです（正確には特定のモジュールのみDEBUGログを有効にする設定が必要です）。

今回使うのは、Netflix OSSである、spectatorのjvm-gcモジュールです。 Netflix OSSにはspectatorやservoといったアプリケーションの監視のためのモジュールが揃っておりこれらも使ってみたいところですが今回は全く利用していません。別の機会に書いてみたいと思います。

さて、話が逸れてしまいましたが、spectatorのjvm-gcモジュールはmavenやgradleを使って依存関係の定義が可能です。

今回はgradleを使ってやっていきますので以下のような記述を追加します。

dependencies {
    compile 'com.netflix.spectator:spectator-ext-gc:0.59.0'
    // ...省略
}

また、先ほどの依存関係を読み込んだらGcLoggerApplicationに以下のコードを追加します。 Application起動時にGcLoggerを初期化して動作するようにしています。ちなみにstartメソッドに渡している、第一引数のnullに対応する引数の型は、GcEventListenerです。今回は利用しないのでnullを渡しています。

    @EventListener
    fun onStartup(e: ApplicationReadyEvent) {
        log.info("started: {}", e)
        GcLogger().start(null)　// Java的には new GcLogger().start(null);
    }

全体のコードとしては以下のような形になりました。

package com.github.wreulicke.gclogger

import com.netflix.spectator.gc.GcLogger
import org.slf4j.Logger
import org.slf4j.LoggerFactory
import org.springframework.boot.autoconfigure.SpringBootApplication
import org.springframework.boot.context.event.ApplicationReadyEvent
import org.springframework.boot.runApplication
import org.springframework.context.event.EventListener
import org.springframework.context.annotation.Bean
import org.springframework.http.MediaType
import org.springframework.web.reactive.function.server.ServerResponse
import org.springframework.web.reactive.function.server.router
import reactor.core.publisher.Flux
import java.util.*
import kotlin.collections.ArrayList


@SpringBootApplication
class GcLoggerApplication{
    companion object {
        private val log:Logger = LoggerFactory.getLogger(GcLoggerApplication::class.java)
    }

    @EventListener
    fun onStartup(e: ApplicationReadyEvent) {
        log.info("started: {}", e)
        GcLogger().start(null)
    }

    // dirty endpoint
    @Bean
    fun routes() = router {
        GET("/test") {
            val list = ArrayList<String>()
            while (true){
                var uuid = UUID.randomUUID().toString()
                list.add(uuid);
                if (uuid == "") break
            }
            log.info(list.toString())
            ServerResponse.ok()
                    .contentType(MediaType.APPLICATION_JSON_UTF8)
                    .body(Flux.just("{\"message\":\"hello\"}"),String::class.java)
        }
    }
}

fun main(args: Array<String>) {
    runApplication<GcLoggerApplication>(*args)
}

ログを確認してみる

では、ここまでで作成したアプリケーションを起動してログを確認してみます。

今回はSlf4j APIの実装としてlogbackを利用します。 logback.xmlに以下の設定を書いておきます。

<?xml version="1.0"?>
<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <Target>System.out</Target>
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>%d{yyyy/MM/dd HH:mm:ss.SSS,JST}+0900 [%.16thread] %-5level %logger{36}:%line - %msg%n</pattern>
        </encoder>
    </appender>
    <logger name="com.netflix.spectator.gc" level="DEBUG" />

    <root level="INFO">
        <appender-ref ref="STDOUT" />
    </root>
</configuration>

logbackの設定を追加したところで、立ち上がってきたところまでのログが以下の内容になります。

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::             (v2.0.0.M6)

2017/11/16 16:27:53.971+0900 [ckground-preinit] INFO  o.h.validator.internal.util.Version:21 - HV000001: Hibernate Validator 6.0.4.Final
2017/11/16 16:27:58.326+0900 [main] INFO  c.g.w.gclogger.GcLoggerApplicationKt:48 - Starting GcLoggerApplicationKt on HL00047.local with PID 83265 (/Users/saito.masaya/repos/spring-sandbox/gclogger/out/production/classes started by saito.masaya in /Users/saito.masaya/repos/spring-sandbox/gclogger)
2017/11/16 16:27:58.328+0900 [main] INFO  c.g.w.gclogger.GcLoggerApplicationKt:651 - No active profile set, falling back to default profiles: default
2017/11/16 16:27:58.423+0900 [main] INFO  o.s.b.w.r.c.ReactiveWebServerApplicationContext:589 - Refreshing org.springframework.boot.web.reactive.context.ReactiveWebServerApplicationContext@1fa121e2: startup date [Thu Nov 16 16:27:58 JST 2017]; root of context hierarchy
2017/11/16 16:28:00.436+0900 [main] INFO  o.s.w.r.f.s.s.RouterFunctionMapping:118 - Mapped (GET && /test) -> org.springframework.web.reactive.function.server.RouterFunctionDsl$GET$1@4aac85fa
2017/11/16 16:28:00.454+0900 [main] INFO  o.s.w.r.h.SimpleUrlHandlerMapping:220 - Mapped URL path [/webjars/**] onto handler of type [class org.springframework.web.reactive.resource.ResourceWebHandler]
2017/11/16 16:28:00.455+0900 [main] INFO  o.s.w.r.h.SimpleUrlHandlerMapping:220 - Mapped URL path [/**] onto handler of type [class org.springframework.web.reactive.resource.ResourceWebHandler]
2017/11/16 16:28:00.571+0900 [main] INFO  o.s.w.r.r.m.a.ControllerMethodResolver:181 - Looking for @ControllerAdvice: org.springframework.boot.web.reactive.context.ReactiveWebServerApplicationContext@1fa121e2: startup date [Thu Nov 16 16:27:58 JST 2017]; root of context hierarchy
2017/11/16 16:28:01.270+0900 [main] INFO  o.s.j.e.a.AnnotationMBeanExporter:434 - Registering beans for JMX exposure on startup
2017/11/16 16:28:06.420+0900 [actor-http-nio-1] INFO  r.ipc.netty.tcp.BlockingNettyContext:238 - Started HttpServer on /0:0:0:0:0:0:0:0:8080
2017/11/16 16:28:06.421+0900 [main] INFO  o.s.b.w.e.netty.NettyWebServer:76 - Netty started on port(s): 8080
2017/11/16 16:28:06.424+0900 [main] INFO  c.g.w.gclogger.GcLoggerApplication:27 - started: org.springframework.boot.context.event.ApplicationReadyEvent
2017/11/16 16:28:06.453+0900 [main] INFO  c.g.w.gclogger.GcLoggerApplicationKt:57 - Started GcLoggerApplicationKt in 23.79 seconds (JVM running for 24.829)

curlで事前に準備したメモリを食うエンドポイントを叩いてみます。

curl http://localhost:8080/test

GCログが出ている様子がうかがえます。

2017/11/16 16:38:45.864+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=9, at=Thu Nov 16 16:37:06 JST 2017, duration=82ms, cause=[Allocation Failure], 0.3GiB => 0.1GiB / 3.2GiB (9.1% => 2.8%)
2017/11/16 16:38:47.080+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=10, at=Thu Nov 16 16:37:06 JST 2017, duration=69ms, cause=[Allocation Failure], 0.3GiB => 0.1GiB / 3.2GiB (9.9% => 3.7%)
2017/11/16 16:38:47.082+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - OLD: PS MarkSweep, id=3, at=Thu Nov 16 16:37:07 JST 2017, duration=386ms, cause=[Ergonomics], 0.1GiB => 0.1GiB / 3.2GiB (3.7% => 3.5%)
2017/11/16 16:38:48.160+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=11, at=Thu Nov 16 16:37:08 JST 2017, duration=158ms, cause=[Allocation Failure], 0.4GiB => 0.2GiB / 3.2GiB (13.6% => 4.9%)
2017/11/16 16:38:49.981+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=12, at=Thu Nov 16 16:37:09 JST 2017, duration=189ms, cause=[Allocation Failure], 0.5GiB => 0.2GiB / 3.2GiB (15.1% => 6.3%)
2017/11/16 16:38:49.982+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - OLD: PS MarkSweep, id=4, at=Thu Nov 16 16:37:09 JST 2017, duration=683ms, cause=[Ergonomics], 0.2GiB => 0.2GiB / 3.2GiB (6.3% => 6.2%)
2017/11/16 16:38:51.768+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=13, at=Thu Nov 16 16:37:11 JST 2017, duration=240ms, cause=[Allocation Failure], 0.7GiB => 0.3GiB / 3.2GiB (21.4% => 8.2%)
2017/11/16 16:38:54.807+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=14, at=Thu Nov 16 16:37:13 JST 2017, duration=385ms, cause=[Allocation Failure], 0.7GiB => 0.3GiB / 3.1GiB (23.6% => 10.5%)
2017/11/16 16:38:54.808+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - OLD: PS MarkSweep, id=5, at=Thu Nov 16 16:37:13 JST 2017, duration=1277ms, cause=[Ergonomics], 0.3GiB => 0.3GiB / 3.1GiB (10.5% => 10.3%)
2017/11/16 16:38:57.150+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=15, at=Thu Nov 16 16:37:16 JST 2017, duration=193ms, cause=[Allocation Failure], 0.8GiB => 0.4GiB / 3.1GiB (25.8% => 12.4%)
2017/11/16 16:38:57.152+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - OLD: PS MarkSweep, id=6, at=Thu Nov 16 16:37:16 JST 2017, duration=899ms, cause=[Ergonomics], 0.4GiB => 0.4GiB / 3.1GiB (12.4% => 12.4%)
2017/11/16 16:38:58.796+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=16, at=Thu Nov 16 16:37:18 JST 2017, duration=256ms, cause=[Allocation Failure], 0.9GiB => 0.5GiB / 3.1GiB (27.9% => 14.4%)
2017/11/16 16:39:00.477+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=17, at=Thu Nov 16 16:37:20 JST 2017, duration=194ms, cause=[Allocation Failure], 0.9GiB => 0.5GiB / 3.1GiB (29.0% => 17.0%)
2017/11/16 16:39:03.499+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=18, at=Thu Nov 16 16:37:22 JST 2017, duration=261ms, cause=[Allocation Failure], 1.0GiB => 0.6GiB / 3.1GiB (31.8% => 19.0%)
2017/11/16 16:39:03.501+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - OLD: PS MarkSweep, id=7, at=Thu Nov 16 16:37:22 JST 2017, duration=1426ms, cause=[Ergonomics], 0.6GiB => 0.6GiB / 3.1GiB (19.0% => 18.5%)
2017/11/16 16:39:05.052+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=19, at=Thu Nov 16 16:37:25 JST 2017, duration=291ms, cause=[Allocation Failure], 1.0GiB => 0.6GiB / 3.1GiB (31.6% => 20.3%)
2017/11/16 16:39:06.402+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=20, at=Thu Nov 16 16:37:26 JST 2017, duration=246ms, cause=[Allocation Failure], 1.0GiB => 0.7GiB / 3.1GiB (33.6% => 22.2%)
2017/11/16 16:39:09.997+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=21, at=Thu Nov 16 16:37:27 JST 2017, duration=408ms, cause=[Allocation Failure], 1.0GiB => 0.7GiB / 3.1GiB (33.0% => 23.6%)
2017/11/16 16:39:09.999+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - OLD: PS MarkSweep, id=8, at=Thu Nov 16 16:37:28 JST 2017, duration=2252ms, cause=[Ergonomics], 0.7GiB => 0.7GiB / 3.1GiB (23.6% => 23.6%)
2017/11/16 16:39:11.100+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=22, at=Thu Nov 16 16:37:31 JST 2017, duration=149ms, cause=[Allocation Failure], 1.1GiB => 0.8GiB / 3.1GiB (34.4% => 25.9%)
2017/11/16 16:39:12.153+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=23, at=Thu Nov 16 16:37:32 JST 2017, duration=77ms, cause=[Allocation Failure], 1.1GiB => 0.8GiB / 3.1GiB (37.0% => 27.4%)
2017/11/16 16:39:13.160+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=24, at=Thu Nov 16 16:37:33 JST 2017, duration=106ms, cause=[Allocation Failure], 1.2GiB => 0.9GiB / 3.0GiB (38.7% => 29.1%)
2017/11/16 16:39:14.081+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=25, at=Thu Nov 16 16:37:34 JST 2017, duration=118ms, cause=[Allocation Failure], 1.2GiB => 0.9GiB / 3.0GiB (38.3% => 30.3%)
2017/11/16 16:39:15.389+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=26, at=Thu Nov 16 16:37:35 JST 2017, duration=257ms, cause=[Allocation Failure], 1.2GiB => 1.0GiB / 3.0GiB (40.0% => 31.8%)
2017/11/16 16:39:19.047+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=27, at=Thu Nov 16 16:37:36 JST 2017, duration=375ms, cause=[Allocation Failure], 1.2GiB => 1.0GiB / 3.0GiB (39.2% => 32.8%)
2017/11/16 16:39:19.049+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - OLD: PS MarkSweep, id=9, at=Thu Nov 16 16:37:36 JST 2017, duration=2593ms, cause=[Ergonomics], 1.0GiB => 1.0GiB / 3.0GiB (32.8% => 32.0%)
2017/11/16 16:39:20.055+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=28, at=Thu Nov 16 16:37:40 JST 2017, duration=247ms, cause=[Allocation Failure], 1.2GiB => 1.0GiB / 3.0GiB (39.3% => 32.9%)
2017/11/16 16:39:20.900+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=29, at=Thu Nov 16 16:37:41 JST 2017, duration=107ms, cause=[Allocation Failure], 1.2GiB => 1.0GiB / 3.0GiB (40.3% => 33.9%)
2017/11/16 16:39:21.612+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=30, at=Thu Nov 16 16:37:41 JST 2017, duration=107ms, cause=[Allocation Failure], 1.2GiB => 1.0GiB / 3.0GiB (41.1% => 34.7%)
2017/11/16 16:39:22.206+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=31, at=Thu Nov 16 16:37:42 JST 2017, duration=108ms, cause=[Allocation Failure], 1.3GiB => 1.1GiB / 3.0GiB (42.4% => 37.3%)
2017/11/16 16:39:22.922+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=32, at=Thu Nov 16 16:37:43 JST 2017, duration=119ms, cause=[Allocation Failure], 1.4GiB => 1.2GiB / 3.0GiB (45.0% => 38.3%)
2017/11/16 16:39:23.826+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=33, at=Thu Nov 16 16:37:43 JST 2017, duration=226ms, cause=[Allocation Failure], 1.4GiB => 1.2GiB / 3.0GiB (45.7% => 39.3%)
2017/11/16 16:39:27.586+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=34, at=Thu Nov 16 16:37:44 JST 2017, duration=387ms, cause=[Allocation Failure], 1.4GiB => 1.2GiB / 3.0GiB (46.7% => 40.3%)
2017/11/16 16:39:27.587+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - OLD: PS MarkSweep, id=10, at=Thu Nov 16 16:37:45 JST 2017, duration=2718ms, cause=[Ergonomics], 1.2GiB => 1.2GiB / 3.0GiB (40.3% => 39.1%)
2017/11/16 16:39:28.164+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=35, at=Thu Nov 16 16:37:48 JST 2017, duration=53ms, cause=[Allocation Failure], 1.4GiB => 1.2GiB / 3.0GiB (46.5% => 40.0%)
2017/11/16 16:39:28.822+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=36, at=Thu Nov 16 16:37:49 JST 2017, duration=107ms, cause=[Allocation Failure], 1.4GiB => 1.2GiB / 3.0GiB (47.4% => 41.0%)
2017/11/16 16:39:29.528+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=37, at=Thu Nov 16 16:37:49 JST 2017, duration=108ms, cause=[Allocation Failure], 1.5GiB => 1.3GiB / 3.0GiB (48.2% => 41.8%)
2017/11/16 16:39:30.304+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=38, at=Thu Nov 16 16:37:50 JST 2017, duration=158ms, cause=[Allocation Failure], 1.5GiB => 1.3GiB / 3.0GiB (49.0% => 42.6%)
2017/11/16 16:39:31.225+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=39, at=Thu Nov 16 16:37:51 JST 2017, duration=195ms, cause=[Allocation Failure], 1.5GiB => 1.3GiB / 3.0GiB (50.4% => 43.6%)
2017/11/16 16:39:32.749+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=40, at=Thu Nov 16 16:37:52 JST 2017, duration=296ms, cause=[Allocation Failure], 1.6GiB => 1.4GiB / 3.0GiB (51.6% => 44.8%)
2017/11/16 16:39:33.816+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=41, at=Thu Nov 16 16:37:53 JST 2017, duration=379ms, cause=[Allocation Failure], 1.6GiB => 1.4GiB / 3.0GiB (52.9% => 46.0%)
2017/11/16 16:39:35.103+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=42, at=Thu Nov 16 16:37:55 JST 2017, duration=434ms, cause=[Allocation Failure], 1.6GiB => 1.4GiB / 3.0GiB (53.9% => 47.0%)
2017/11/16 16:39:40.653+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - YOUNG: PS Scavenge, id=43, at=Thu Nov 16 16:37:56 JST 2017, duration=488ms, cause=[Allocation Failure], 1.6GiB => 1.4GiB / 3.0GiB (54.4% => 48.0%)
2017/11/16 16:39:40.654+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - OLD: PS MarkSweep, id=11, at=Thu Nov 16 16:37:56 JST 2017, duration=4433ms, cause=[Ergonomics], 1.4GiB => 1.4GiB / 3.0GiB (48.0% => 47.9%)
2017/11/16 16:39:44.388+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - OLD: PS MarkSweep, id=12, at=Thu Nov 16 16:38:01 JST 2017, duration=3119ms, cause=[Ergonomics], 1.7GiB => 1.5GiB / 3.0GiB (55.3% => 48.9%)
2017/11/16 16:39:48.373+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - OLD: PS MarkSweep, id=13, at=Thu Nov 16 16:38:05 JST 2017, duration=3511ms, cause=[Ergonomics], 1.6GiB => 1.5GiB / 3.0GiB (53.4% => 49.4%)
2017/11/16 16:39:52.792+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - OLD: PS MarkSweep, id=14, at=Thu Nov 16 16:38:09 JST 2017, duration=4076ms, cause=[Ergonomics], 1.6GiB => 1.5GiB / 3.0GiB (53.4% => 49.9%)
2017/11/16 16:39:56.649+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - OLD: PS MarkSweep, id=15, at=Thu Nov 16 16:38:13 JST 2017, duration=3516ms, cause=[Ergonomics], 1.6GiB => 1.5GiB / 3.0GiB (53.4% => 50.4%)
2017/11/16 16:40:00.288+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - OLD: PS MarkSweep, id=16, at=Thu Nov 16 16:38:17 JST 2017, duration=3349ms, cause=[Ergonomics], 1.6GiB => 1.5GiB / 3.0GiB (53.4% => 50.8%)
2017/11/16 16:40:03.816+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - OLD: PS MarkSweep, id=17, at=Thu Nov 16 16:38:20 JST 2017, duration=3250ms, cause=[Ergonomics], 1.6GiB => 1.5GiB / 3.0GiB (53.4% => 51.1%)
2017/11/16 16:40:07.122+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - OLD: PS MarkSweep, id=18, at=Thu Nov 16 16:38:24 JST 2017, duration=3122ms, cause=[Ergonomics], 1.6GiB => 1.5GiB / 3.0GiB (53.4% => 51.4%)
2017/11/16 16:40:10.260+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - OLD: PS MarkSweep, id=19, at=Thu Nov 16 16:38:27 JST 2017, duration=2976ms, cause=[Ergonomics], 1.6GiB => 1.6GiB / 3.0GiB (53.4% => 51.7%)
2017/11/16 16:40:18.250+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - OLD: PS MarkSweep, id=20, at=Thu Nov 16 16:38:30 JST 2017, duration=3710ms, cause=[Ergonomics], 1.6GiB => 1.6GiB / 3.0GiB (51.9% => 51.7%)
2017/11/16 16:40:18.250+0900 [Service Thread] DEBUG com.netflix.spectator.gc.GcLogger:200 - OLD: PS MarkSweep, id=21, at=Thu Nov 16 16:38:34 JST 2017, duration=4249ms, cause=[Allocation Failure], 1.6GiB => 1.6GiB / 3.0GiB (51.7% => 51.7%)
2017/11/16 16:40:18.269+0900 [actor-http-nio-2] WARN  i.n.u.c.AbstractEventExecutor:146 - A task raised an exception. Task: reactor.ipc.netty.channel.ContextHandler$$Lambda$273/689714991@7ad31c4
java.lang.OutOfMemoryError: Java heap space
    at java.util.Arrays.copyOf(Arrays.java:3181)
    at java.util.ArrayList.grow(ArrayList.java:261)
    at java.util.ArrayList.ensureExplicitCapacity(ArrayList.java:235)
    at java.util.ArrayList.ensureCapacityInternal(ArrayList.java:227)
    at java.util.ArrayList.add(ArrayList.java:458)
    at com.github.wreulicke.gclogger.GcLoggerApplication$routes$1$1.invoke(GcLoggerApplication.kt:38)
    at com.github.wreulicke.gclogger.GcLoggerApplication$routes$1$1.invoke(GcLoggerApplication.kt:20)
    at org.springframework.web.reactive.function.server.RouterFunctionDsl$GET$1.handle(RouterFunctionDsl.kt:155)
    at org.springframework.web.reactive.function.server.support.HandlerFunctionAdapter.handle(HandlerFunctionAdapter.java:61)
    at org.springframework.web.reactive.DispatcherHandler.invokeHandler(DispatcherHandler.java:168)
    at org.springframework.web.reactive.DispatcherHandler.lambda$handle$1(DispatcherHandler.java:160)
    at org.springframework.web.reactive.DispatcherHandler$$Lambda$292/1094530475.apply(Unknown Source)
    at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:118)
    at reactor.core.publisher.FluxSwitchIfEmpty$SwitchIfEmptySubscriber.onNext(FluxSwitchIfEmpty.java:67)
    at reactor.core.publisher.MonoNext$NextSubscriber.onNext(MonoNext.java:76)
    at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.innerNext(FluxConcatMap.java:271)
    at reactor.core.publisher.FluxConcatMap$ConcatMapInner.onNext(FluxConcatMap.java:798)
    at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onNext(FluxMapFuseable.java:115)
    at reactor.core.publisher.Operators$ScalarSubscription.request(Operators.java:1649)
    at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.request(FluxMapFuseable.java:156)
    at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.set(Operators.java:1463)
    at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onSubscribe(Operators.java:1337)
    at reactor.core.publisher.FluxMapFuseable$MapFuseableSubscriber.onSubscribe(FluxMapFuseable.java:90)
    at reactor.core.publisher.MonoJust.subscribe(MonoJust.java:54)
    at reactor.core.publisher.MonoMapFuseable.subscribe(MonoMapFuseable.java:59)
    at reactor.core.publisher.Mono.subscribe(Mono.java:2913)
    at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.drain(FluxConcatMap.java:418)
    at reactor.core.publisher.FluxConcatMap$ConcatMapImmediate.onSubscribe(FluxConcatMap.java:210)
    at reactor.core.publisher.FluxIterable.subscribe(FluxIterable.java:91)
    at reactor.core.publisher.FluxIterable.subscribe(FluxIterable.java:55)
    at reactor.core.publisher.FluxConcatMap.subscribe(FluxConcatMap.java:121)
    at reactor.core.publisher.MonoNext.subscribe(MonoNext.java:40)

最終的にはOutOfMemmoryErrorが発生して終了してしまいました。

これだけではつまらないので・・・

これだけではつまらないので、JSON形式でログを出力してみます。これはlogbackの設定を追加するだけです。

まずは依存関係を追加します。

    compile "ch.qos.logback.contrib:logback-json-core:0.1.2"
    compile "ch.qos.logback.contrib:logback-json-classic:0.1.2"
    compile "ch.qos.logback.contrib:logback-jackson:0.1.2"

また、追加したモジュールを使った設定をlogback.xmlに記述します。

<?xml version="1.0"?>
<configuration>
    <!-- 
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <Target>System.out</Target>
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>%d{yyyy/MM/dd HH:mm:ss.SSS,JST}+0900 [%.16thread] %-5level %logger{36}:%line - %msg%n</pattern>
        </encoder>
    </appender>
    -->

    <!-- 下の設定を追加した -->
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <Target>System.out</Target>
        <encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">
            <layout class="ch.qos.logback.contrib.json.classic.JsonLayout">
                <jsonFormatter class="ch.qos.logback.contrib.jackson.JacksonJsonFormatter">
                </jsonFormatter>
                <timestampFormat>yyyy-MM-dd'T'HH:mm:ss.SSSXXX</timestampFormat>
                <includeContextName>false</includeContextName>
                <appendLineSeparator>true</appendLineSeparator>
            </layout>
            <charset>UTF-8</charset>
        </encoder>
    </appender>

    <logger name="com.netflix.spectator.gc" level="DEBUG" />

    <root level="INFO">
        <appender-ref ref="STDOUT" />
    </root>

</configuration>

JSON形式のログが出ています。

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::             (v2.0.0.M6)

{"timestamp":"2017-11-16T17:33:49.873+09:00","level":"INFO","thread":"background-preinit","logger":"org.hibernate.validator.internal.util.Version","message":"HV000001: Hibernate Validator 6.0.4.Final"}
{"timestamp":"2017-11-16T17:33:54.169+09:00","level":"INFO","thread":"main","logger":"com.github.wreulicke.gclogger.GcLoggerApplicationKt","message":"Starting GcLoggerApplicationKt on HL00047.local with PID 84074 (/Users/saito.masaya/repos/spring-sandbox/gclogger/out/production/classes started by saito.masaya in /Users/saito.masaya/repos/spring-sandbox/gclogger)"}
{"timestamp":"2017-11-16T17:33:54.171+09:00","level":"INFO","thread":"main","logger":"com.github.wreulicke.gclogger.GcLoggerApplicationKt","message":"No active profile set, falling back to default profiles: default"}
{"timestamp":"2017-11-16T17:33:54.291+09:00","level":"INFO","thread":"main","logger":"org.springframework.boot.web.reactive.context.ReactiveWebServerApplicationContext","message":"Refreshing org.springframework.boot.web.reactive.context.ReactiveWebServerApplicationContext@21e360a: startup date [Thu Nov 16 17:33:54 JST 2017]; root of context hierarchy"}
{"timestamp":"2017-11-16T17:33:57.160+09:00","level":"INFO","thread":"main","logger":"org.springframework.web.reactive.function.server.support.RouterFunctionMapping","message":"Mapped (GET && /test) -> org.springframework.web.reactive.function.server.RouterFunctionDsl$GET$1@59429fac"}
{"timestamp":"2017-11-16T17:33:57.182+09:00","level":"INFO","thread":"main","logger":"org.springframework.web.reactive.handler.SimpleUrlHandlerMapping","message":"Mapped URL path [/webjars/**] onto handler of type [class org.springframework.web.reactive.resource.ResourceWebHandler]"}
{"timestamp":"2017-11-16T17:33:57.182+09:00","level":"INFO","thread":"main","logger":"org.springframework.web.reactive.handler.SimpleUrlHandlerMapping","message":"Mapped URL path [/**] onto handler of type [class org.springframework.web.reactive.resource.ResourceWebHandler]"}
{"timestamp":"2017-11-16T17:33:57.358+09:00","level":"INFO","thread":"main","logger":"org.springframework.web.reactive.result.method.annotation.ControllerMethodResolver","message":"Looking for @ControllerAdvice: org.springframework.boot.web.reactive.context.ReactiveWebServerApplicationContext@21e360a: startup date [Thu Nov 16 17:33:54 JST 2017]; root of context hierarchy"}
{"timestamp":"2017-11-16T17:33:58.101+09:00","level":"INFO","thread":"main","logger":"org.springframework.jmx.export.annotation.AnnotationMBeanExporter","message":"Registering beans for JMX exposure on startup"}
{"timestamp":"2017-11-16T17:34:03.294+09:00","level":"INFO","thread":"reactor-http-nio-1","logger":"reactor.ipc.netty.tcp.BlockingNettyContext","message":"Started HttpServer on /0:0:0:0:0:0:0:0:8080"}
{"timestamp":"2017-11-16T17:34:03.295+09:00","level":"INFO","thread":"main","logger":"org.springframework.boot.web.embedded.netty.NettyWebServer","message":"Netty started on port(s): 8080"}
{"timestamp":"2017-11-16T17:34:03.298+09:00","level":"INFO","thread":"main","logger":"com.github.wreulicke.gclogger.GcLoggerApplication","message":"started: org.springframework.boot.context.event.ApplicationReadyEvent"}
{"timestamp":"2017-11-16T17:34:03.336+09:00","level":"INFO","thread":"main","logger":"com.github.wreulicke.gclogger.GcLoggerApplicationKt","message":"Started GcLoggerApplicationKt in 25.459 seconds (JVM running for 28.065)"}
{"timestamp":"2017-11-16T17:35:25.908+09:00","level":"DEBUG","thread":"Service Thread","logger":"com.netflix.spectator.gc.GcLogger","message":"YOUNG: PS Scavenge, id=10, at=Thu Nov 16 17:35:25 JST 2017, duration=16ms, cause=[Allocation Failure], 0.2GiB => 0.1GiB / 3.2GiB (5.4% => 2.4%)"}
{"timestamp":"2017-11-16T17:35:26.365+09:00","level":"DEBUG","thread":"Service Thread","logger":"com.netflix.spectator.gc.GcLogger","message":"YOUNG: PS Scavenge, id=11, at=Thu Nov 16 17:35:26 JST 2017, duration=56ms, cause=[Allocation Failure], 0.2GiB => 0.1GiB / 3.2GiB (6.9% => 2.9%)"}
{"timestamp":"2017-11-16T17:35:26.990+09:00","level":"DEBUG","thread":"Service Thread","logger":"com.netflix.spectator.gc.GcLogger","message":"YOUNG: PS Scavenge, id=12, at=Thu Nov 16 17:35:26 JST 2017, duration=41ms, cause=[Allocation Failure], 0.3GiB => 0.1GiB / 3.2GiB (7.9% => 3.6%)"}
{"timestamp":"2017-11-16T17:35:28.375+09:00","level":"DEBUG","thread":"Service Thread","logger":"com.netflix.spectator.gc.GcLogger","message":"YOUNG: PS Scavenge, id=13, at=Thu Nov 16 17:35:27 JST 2017, duration=93ms, cause=[Allocation Failure], 0.3GiB => 0.1GiB / 3.2GiB (10.2% => 4.4%)"}
{"timestamp":"2017-11-16T17:35:28.377+09:00","level":"DEBUG","thread":"Service Thread","logger":"com.netflix.spectator.gc.GcLogger","message":"OLD: PS MarkSweep, id=3, at=Thu Nov 16 17:35:27 JST 2017, duration=542ms, cause=[Ergonomics], 0.1GiB => 0.1GiB / 3.2GiB (4.4% => 4.3%)"}
{"timestamp":"2017-11-16T17:35:29.078+09:00","level":"DEBUG","thread":"Service Thread","logger":"com.netflix.spectator.gc.GcLogger","message":"YOUNG: PS Scavenge, id=14, at=Thu Nov 16 17:35:29 JST 2017, duration=57ms, cause=[Allocation Failure], 0.3GiB => 0.2GiB / 3.2GiB (10.9% => 5.3%)"}
{"timestamp":"2017-11-16T17:35:30.885+09:00","level":"DEBUG","thread":"Service Thread","logger":"com.netflix.spectator.gc.GcLogger","message":"YOUNG: PS Scavenge, id=15, at=Thu Nov 16 17:35:30 JST 2017, duration=210ms, cause=[Allocation Failure], 0.5GiB => 0.2GiB / 3.2GiB (15.5% => 6.7%)"}
{"timestamp":"2017-11-16T17:35:30.886+09:00","level":"DEBUG","thread":"Service Thread","logger":"com.netflix.spectator.gc.GcLogger","message":"OLD: PS MarkSweep, id=4, at=Thu Nov 16 17:35:30 JST 2017, duration=574ms, cause=[Ergonomics], 0.2GiB => 0.2GiB / 3.2GiB (6.7% => 6.5%)"}
{"timestamp":"2017-11-16T17:35:31.952+09:00","level":"DEBUG","thread":"Service Thread","logger":"com.netflix.spectator.gc.GcLogger","message":"YOUNG: PS Scavenge, id=16, at=Thu Nov 16 17:35:31 JST 2017, duration=172ms, cause=[Allocation Failure], 0.5GiB => 0.3GiB / 3.2GiB (16.8% => 7.9%)"}
{"timestamp":"2017-11-16T17:35:34.398+09:00","level":"DEBUG","thread":"Service Thread","logger":"com.netflix.spectator.gc.GcLogger","message":"YOUNG: PS Scavenge, id=17, at=Thu Nov 16 17:35:33 JST 2017, duration=225ms, cause=[Allocation Failure], 0.7GiB => 0.3GiB / 3.1GiB (22.0% => 10.1%)"}
{"timestamp":"2017-11-16T17:35:34.400+09:00","level":"DEBUG","thread":"Service Thread","logger":"com.netflix.spectator.gc.GcLogger","message":"OLD: PS MarkSweep, id=5, at=Thu Nov 16 17:35:33 JST 2017, duration=896ms, cause=[Ergonomics], 0.3GiB => 0.3GiB / 3.1GiB (10.1% => 9.8%)"}
{"timestamp":"2017-11-16T17:35:36.064+09:00","level":"DEBUG","thread":"Service Thread","logger":"com.netflix.spectator.gc.GcLogger","message":"YOUNG: PS Scavenge, id=18, at=Thu Nov 16 17:35:35 JST 2017, duration=224ms, cause=[Allocation Failure], 0.8GiB => 0.4GiB / 3.1GiB (25.3% => 12.3%)"}
{"timestamp":"2017-11-16T17:35:37.437+09:00","level":"DEBUG","thread":"Service Thread","logger":"com.netflix.spectator.gc.GcLogger","message":"YOUNG: PS Scavenge, id=19, at=Thu Nov 16 17:35:37 JST 2017, duration=150ms, cause=[Allocation Failure], 0.8GiB => 0.4GiB / 3.1GiB (27.1% => 14.2%)"}
{"timestamp":"2017-11-16T17:35:40.428+09:00","level":"DEBUG","thread":"Service Thread","logger":"com.netflix.spectator.gc.GcLogger","message":"YOUNG: PS Scavenge, id=20, at=Thu Nov 16 17:35:38 JST 2017, duration=314ms, cause=[Allocation Failure], 0.9GiB => 0.5GiB / 3.1GiB (29.2% => 16.3%)"}